Amazon RDS for MySQL でいつからレプリケーションエラーが発生しているかを確認したい

コンバンハ、千葉（幸）です。

Amazon RDS for MySQL を「プライマリ1台、レプリカ1台」で運用している際に、レプリカ側でレプリケーションエラーが発生していることがありました。

レプリカインスタンスの「接続とセキュリティ」タブから確認すると、このようになっています。

これが果たしていつから発生している事象なのか？を調査しようと思った際に、取りうる手段や方法を調べるのに20分くらいかかりました。誰かの20分を節約するためにブログに残しておきます。

なお、このエントリではエラーの原因や解消方法には触れません。あくまで「いつからエラーなのか」を特定することに範囲を限定します。トラブルシューティングの観点について知りたい方は、以下をご参考ください。

• Amazon RDS のトラブルシューティング - Amazon Relational Database Service

まとめ

• CloudWatch メトリクスReplicaLagが-1になっているかで確認できる
• RDS イベントではエラーメッセージも含めて確認できる
  • コンソールから確認できるのは最大24時間、AWS CLI であれば過去14日間まで確認できる
• AWS Config リソースタイムラインでも確認できるが、リアルタイムではないので参考程度に
• aws rds describe-db-instancesでは「いつから」の情報は取得できない

ReplicaLag メトリクスから確認する

おそらく一番手っ取り早いのはCloudWatchメトリクスReplicaLagを確認することです。

If the ReplicaLag metric returns -1, then replication is currently not active.

（日本語版）

ReplicaLag メトリクスにより -1 が返された場合、レプリケーションは現在アクティブではありません。

• Working with DB instance read replicas - Amazon Relational Database Service

レプリケーションエラーが発生していればレプリケーションはアクティブではないはずですので、メトリクスで-1が記録され始めたタイミングを確認すると良さそうです。

レプリカインスタンスの詳細画面の「モニタリング」タブから、ReplicaLagメトリクスを確認します。

一定時期を境にメトリクスが描画されていません。カーソルを合わせてみると、グラフ描画がなされなくなった後は-1が記録されていました。この辺りがエラーの発生タイミングだろう、とあたりをつけられます。

RDS イベントから確認する

別のアプローチとして、RDS コンソールの「イベント」からレプリケーションエラーのイベントを確認する手法もあります。エラーメッセージの内訳も確認できます。

ただし、ここで確認できるイベントは最大で過去24時間分です。それ以前からレプリケーションエラーが発生している場合、ここでは追い切れません。

（なお、インスタンス詳細画面の「ログとイベント」タブ→「最近のイベント」からもイベントが確認できますが、参照できるイベント量はさらに少ないです。）

AWS CLI コマンドであれば最大で過去14日間まで遡って情報を取得できます。レプリケーションエラー発生がその期間内であれば、このコマンドで発生タイミングを確認できます。

• describe-events — AWS CLI 2.11.25 Command Reference

リファレンスから引用したOutput例は以下です。

{
    "Events": [
        {
            "SourceType": "db-instance",
            "SourceIdentifier": "test-instance",
            "EventCategories": [
                "backup"
            ],
            "Message": "Backing up DB instance",
            "Date": "2018-07-31T23:09:23.983Z",
            "SourceArn": "arn:aws:rds:us-east-1:123456789012:db:test-instance"
        },
        {
            "SourceType": "db-instance",
            "SourceIdentifier": "test-instance",
            "EventCategories": [
                "backup"
            ],
            "Message": "Finished DB Instance backup",
            "Date": "2018-07-31T23:15:13.049Z",
            "SourceArn": "arn:aws:rds:us-east-1:123456789012:db:test-instance"
        }
    ]
}

特定のインスタンスを指定し、「14日前から」「カテゴリがread replicaのものを」「イベントの日時のみ」5個取得する例です。

$ aws rds describe-events\
  --source-identifier DB_INSTANCE_NAME\
  --source-type db-instance\
  --start-time $(date -v -14d "+%Y-%m-%dT%H:%M:%SZ")\
  --event-categories "read replica"\
  --query 'Events[].Date'\
  --max-items 5
[
    "2023-05-30T05:05:29.747000+00:00",
    "2023-05-30T05:06:29.774000+00:00",
    "2023-05-30T05:07:29.759000+00:00",
    "2023-05-30T05:08:29.762000+00:00",
    "2023-05-30T05:09:29.759000+00:00"
]

古い順にイベントが取得できるため、14日以内であれば発生タイミングを特定できます。

イベントのメッセージも確認したい場合は例えば以下のように指定できます。

$ aws rds describe-events\
  --source-identifier DB_INSTANCE_NAME\
  --source-type db-instance\
  --duration 20160\
  --event-categories "read replica"\
  --query 'Events[].[Date,Message]'\
  --output text\
  --max-items 5
2023-05-30T05:05:29.747000+00:00        Read Replica Replication Error -  SQLError:  1292, reason:  Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略;
2023-05-30T05:06:29.774000+00:00        Read Replica Replication Error -  SQLError:  1292, reason:  Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略;
2023-05-30T05:07:29.759000+00:00        Read Replica Replication Error -  SQLError:  1292, reason:  Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略;

↑「N日前」の指定は--start-timeでなく--durationでも指定できます。上の例では、60 * 24 * 14 = 20160 分で指定しています。

メトリクスとあわせて確認すれば、より精度の高い情報が得られるでしょう。

AWS Config リソースタイムラインから確認する

あえてこの手法を使うメリットがあるかと言われると微妙ですが、AWS Config のリソースタイムラインからでもステータスの変わったタイミングが確認できます。

AWS Config コンソール「リソース」で以下を指定してフィルタリングし、対象のリソースを選択して「リソースタイムライン」を表示します。

• リソースカテゴリ：AWS リソース
• リソースタイプ：AWS RDS DBInstance
• リソース識別子：（レプリカインスタンス名）

タイムラインの表示イメージはこちら。レプリケーションのステータスが変わったタイミングが記録されています。

ただ、AWS Config による記録はリアルタイムで行われているわけではないので、ここで確認できる日時は参考程度にとどめておいた方が良さそうです。

今回のケースでは、「RDSイベントでレプリケーションエラーが記録され始めたタイミング」と「リソースタイムライン上でレプリケーションステータスの変更が記録されたタイミング」は21時間ほどズレがありました。

余談：describe-db-instances では「いつから」はわからない

ここまでのいずれかの手法で、「いつからレプリケーションエラーが発生しているか」は概ね特定できているはずです。

それらの手法とは異なり発生タイミングは取得できないのですが、参考までに DB インスタンスの詳細を表示する AWS CLI コマンドも試しておきます。

• describe-db-instances — AWS CLI 2.11.25 Command Reference

実行例は以下です。対象に指定しているのはレプリカインスタンスです。（DBインスタンスのパラメータ多いな！というのに気付かされます。）

$ aws rds describe-db-instances --db-instance-identifier DB-INSTANCE-NAME
{
    "DBInstances": [
        {
            "DBInstanceIdentifier": "DB-INSTANCE-NAME",
            "DBInstanceClass": "db.r5.large",
            "Engine": "mysql",
            "DBInstanceStatus": "available",
            "MasterUsername": "username",
            "DBName": "dbname",
            "Endpoint": {
                "Address": "DB-INSTANCE-NAME.xxxxxxxx.ap-northeast-1.rds.amazonaws.com",
                "Port": 3306,
                "HostedZoneId": "xxxxxxxx"
            },
            "AllocatedStorage": 2500,
            "InstanceCreateTime": "2015-03-10T05:22:35.905000+00:00",
            "PreferredBackupWindow": "05:00-05:30",
            "BackupRetentionPeriod": 0,
            "DBSecurityGroups": [],
            "VpcSecurityGroups": [
                {
                    "VpcSecurityGroupId": "sg-xxxxxxxx",
                    "Status": "active"
                }
            ],
            "DBParameterGroups": [
                {
                    "DBParameterGroupName": "mysql5-7",
                    "ParameterApplyStatus": "in-sync"
                }
            ],
            "AvailabilityZone": "ap-northeast-1a",
            "DBSubnetGroup": {
                "DBSubnetGroupName": "sb-gp",
                "DBSubnetGroupDescription": "sb-gp",
                "VpcId": "vpc-xxxxxxxx",
                "SubnetGroupStatus": "Complete",
                "Subnets": [
                    {
                        "SubnetIdentifier": "subnet-xxxxxxxx",
                        "SubnetAvailabilityZone": {
                            "Name": "ap-northeast-1a"
                        },
                        "SubnetOutpost": {},
                        "SubnetStatus": "Active"
                    },
                    {
                        "SubnetIdentifier": "subnet-xxxxxxxx",
                        "SubnetAvailabilityZone": {
                            "Name": "ap-northeast-1c"
                        },
                        "SubnetOutpost": {},
                        "SubnetStatus": "Active"
                    }
                ]
            },
            "PreferredMaintenanceWindow": "sat:06:00-sat:06:30",
            "PendingModifiedValues": {},
            "MultiAZ": false,
            "EngineVersion": "5.7.38",
            "AutoMinorVersionUpgrade": true,
            "ReadReplicaSourceDBInstanceIdentifier": "SOURCE_INSTANCE_NAME",
            "ReadReplicaDBInstanceIdentifiers": [],
            "LicenseModel": "general-public-license",
            "OptionGroupMemberships": [
                {
                    "OptionGroupName": "default:mysql-5-7",
                    "Status": "in-sync"
                }
            ],
            "PubliclyAccessible": false,
            "StatusInfos": [
                {
                    "StatusType": "read replication",
                    "Normal": false,
                    "Status": "error",
                    "Message": "Apply Error 1292: Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略"
                }
            ],
            "StorageType": "gp2",
            "DbInstancePort": 0,
            "StorageEncrypted": false,
            "DbiResourceId": "db-XXXXXXXXXX",
            "CACertificateIdentifier": "rds-ca-2019",
            "DomainMemberships": [],
            "CopyTagsToSnapshot": false,
            "MonitoringInterval": 0,
            "DBInstanceArn": "arn:aws:rds:ap-northeast-1:000000000000:db:DB-INSTANCE-NAME",
            "IAMDatabaseAuthenticationEnabled": false,
            "DeletionProtection": false,
            "AssociatedRoles": [],
            "TagList": [
                {
                    "Key": "Test",
                    "Value": "Test"
                }
            ],
            "CustomerOwnedIpEnabled": false,
            "ActivityStreamStatus": "stopped",
            "BackupTarget": "region",
            "NetworkType": "IPV4"
        }
    ]
}

ステータスに関連する部分だけ抽出します。

$ aws rds describe-db-instances --db-instance-identifier DB-INSTANCE-NAME\
  --query 'DBInstances[].StatusInfos'
[
    [
        {
            "StatusType": "read replication",
            "Normal": false,
            "Status": "error",
            "Message": "Apply Error 1292: Error 'Truncated incorrect DOUBLE value: 'null'' on query. Default database: 以下略"
        }
    ]
]

ステータスでエラーが発生していることは分かりますが、それがいつからなのかはこのコマンドでは取得できません。このコマンドで取得できるのとほぼ同等の内容は AWS Config によって定期的に収集されていますので、値の変化の記録は Config の役割である、と言えるかもしれません。

終わりに

Amazon RDS for MySQL でいつからレプリケーションエラーが発生しているかを確認したい、という内容でした。

エラーの発生を即時に気づけることに越したことはないですが、途中から調査目的で参画する、など後追いで発生タイミングを確認したいケースがあるかと思います。（今回のわたしのように。）そんな方の調査時間の節約に役立てば幸いです。

以上、 チバユキ (@batchicchi) がお送りしました。

参考

• 24時間以上前の RDS イベントログを確認する方法 | DevelopersIO
• Amazon RDS for MySQLのレプリケーションで遅延が発生しているかどうかを確認する方法 | DevelopersIO